记一次日志引起的服务端问题排查经历
本文字数：7655字
预计阅读时间：20分钟
1、源起：
一天中午休息饭后散步时，隔壁组的王老哥提到，他们组的负责的一个Java服务最近一段时间，每天0点，经常会收到网关报警：提示接口响应慢。老板天天追问，但是服务使用的spring组件虽然支持在tomcat线程使用率超过一定数值后自动生成现场快照，但是不知道是什么原因，查看相关时间点附近生成的快照文件，里面的内容均正常，日志内容除问题时间点缺了一些之外，也没有异常现象，所以对于该问题，他是：老虎吃天，无从下爪。
我一听，瞬间来了精神：“老王啊老王，你也有今天。。。”，
老王：“来来来，你接力！！！搞定请你吃饭。”
看在吃饭的份上，我答应了。于是有了如下的问题排查过程。
2、问题定位过程：
既然抓不到现场的快照，没有直接的线索，就只能先收集一些有用的线索。
2.1 线索收集
先从JVM服务运行指标入手,采集相关时间点连续三天的接口平均响应和Tomcat线程池使用率的指标数据，都呈现类似的状态，如下图所示：
没有线程dump信息，那还是从指标入手，只不过这次因为前面分析有线程阻塞，并且也猜测了一些可能的原因，那么要检查当时部署环境（因为是部署在k8s中，所以是运行环境是容器）的指标状态，CPU/内存/网络IO/磁盘IO指标数据如下表所示：
通过分析相关时间点的容器指标，发现：除磁盘读操作之外，其它基本正常。
2.2 线索总结
异常的原因是由：
服务本身的
实例相关的(即每个实例都要执行)
同时间相关的
有阻塞(带锁)行为的
持续大量磁盘读的
操作导致。
2.3 确定排查方向
基于上述分析过程、相关线索的总结，结合相关服务的业务功能和过往经验，初步将异常的原因锁定在如下内容：
A 服务的定时任务, B 服务的日志操作, C 其它。
2.3.1定时任务
| 1 | 【服务本身的】 | 是 |
|---|---|---|
| 2 | 【实例相关的(即每个实例都要执行)】 | 不一定相关 |
| 3 | 【同时间相关的】 | 是 |
| 4 | 【有阻塞(带锁)行为的】 | 不确定 |
| 5 | 【持续大量磁盘读的】 | 不确定 |
经排查代码，没有符合条件的相关时间点的定时任务
2.3.2日志操作：
| 1 | 【服务本身的】 | 是 |
|---|---|---|
| 2 | 【实例相关的(即每个实例都要执行)】 | 是 |
| 3 | 【同时间相关的】 | 是，日志按天滚动备份 |
| 4 | 【有阻塞(带锁)行为的】 | 确定，从线程dump看到，确实是存在同步行为 |
| 5 | 【持续大量磁盘读的】 | 确定，从线程dump看到，确实是存在大量读取日志文件的操作 |
2.4 从日志角度排查
因为没有找到符合相关条件的定时任务，所以转而排查日志,根据目前手里的线索，需要解决如下两个问题：
A 确定异常是否由日志操作导致， B 如果确定是日志操作导致，那需要测试环境稳定复现并且详细解释之。
先从问题A开始，一般来说，日志功能是稳定可用的(本文所述服务使用的是Logback框架)，异常都是出在配置上。所以采用控制变量法，简化日志配置，保证：
A 精简性，删除无用的 Appender，只保留最基本功能, B 正确性，同其它正常服务的日志配置对比, C 对业务影响最低,使用异步日志，保证不会阻塞业务线程。
在重新配置日志配置之前，先检查当前的配置,发现确实存在一些问题:
A 打印了控制台日志( console.log，相关文件有32GB)，B 标准输出 stdout的日志文件关于日志文件滚动备件的存储目录配置有错误：输出到${log.dir}/stdout.%d{yyyy-MM-dd}.log,但是${log.dir}这个环境变量并不存在，登录到容器中查询日志滚动备份的文件,发现实际是写入到:/opt/log.dir_IS_UNDEFINED。
按前面的要求更新配置，采用灰度方式部署服务：保留现有的节点，增加两个使用新配置的节点。
关于灰度部署的Tips:
A 方便对比调整前后的状态， B 新增两个是为了降低单个节点测试结果的偶然性， C 只新增加两个是为了尽量降低对线上服务的影响。
结果：新部署的两个灰度节点在异常发生的相关时间点没有发生线程阻塞的现象，恢复正常。未修改配置文件的旧节点异常依旧复现。如下图：
结论：异常确定是由日志配置错误导致的。通知老王基于新的日志配置更新服务，解决线上问题。
3 、探个究竟
线上问题已经解决， 一切恢复了平静。目前仍然遗留两个问题需要解决：
A 纠竟是日志的什么操作导致的线程异常阻塞， B 为什么框架提供基于Tomcat线程池使用率自动生成JVM快照的功能总是拿不到有用的信息。
3.1 复现过程
解决以上内容最有效的方式肯定是通过在本地环境复现。因为确定同日志操作相关，那么只需要准备：
A 一个简单的spring-boot-webmvc项目， B 接入与服务相同日志框架及配置（包含之前发现的错误的配置项）， C 根据前面排查异常时收集的线索，同时间相关的日志操作是日志按天滚动备份，因为是要模拟这个现象，所以可以把日期格式修改成按分钟滚动备份， D 服务启动完成后模拟持续的日志打印操作， E 使用Windows10+WSL2环境运行模拟环境。
日志配置logback.xml如下：
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<property name="LOG_HOME" value="/data/logs"/>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_HOME}/stdout.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.dir}/stdout.%d{yyyy-MM-dd_HH_mm}.log</FileNamePattern>
<MaxHistory>7</MaxHistory>
</rollingPolicy>
<encoder>
<Pattern>>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="FILE"/>
</root>
</configuration>
启动服务，观察到工作线程是能够正常打印日志。通过仔细对比JVM的运行环境，发现:
A 服务是在容器上运行,服务部署的位置是
/opt下，B 日志文件默认是存储到
/data/logs目录下，C 日志文件的滚动备份因为环境变量配置错误实际是存储到
/opt/log.dir_IS_UNDEFINED目录下，
这其中/data是容器挂载的主机目录,/opt是容器的内部目录，从容器的进程角度看两者不属于同一个存储卷。因为使用的是Windows10+WSL2，JVM运行在WSL2中，并且在WSL2中默认是挂载了Windows10的分区的，所以只需要修改模拟环境的日志滚动备份的存储目录到Window10的主机的某个分区即可。添加${log.dir}变量，指向到Windows10的目录:/mnt/c/logs,修改后的logback.xml如下：
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<property name="LOG_HOME" value="/data/logs"/>
<property name="log.dir" value="/mnt/c/logs"/>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_HOME}/stdout.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<FileNamePattern>${log.dir}/stdout.%d{yyyy-MM-dd_HH_mm}.log</FileNamePattern>
<MaxHistory>7</MaxHistory>
</rollingPolicy>
<encoder>
<Pattern>>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="FILE"/>
</root>
</configuration>
重新启动服务，工作线程是依然能够正常打印日志。再次对比环境，没有发现什么相关差异，重新登录到服务查看服务生成的日志文件：每天生成的日志的容量单位是GB，而模拟环境的日志文件，单位是MB。结合之前发现的异常期间有大量的IO操作，这有可能是问题所在。
尝试在启动模拟服务前先手工填充下日志文件让它足够大（至少GB为单位）。
重新启动服务，观察，工作线程卡住了：**!!!!!!异常状态成功复现!!!!!!**
3.2 分析过程
3.2.1 关于线程阻塞问题
现场有了，暂停JVM，查看相关工作线程的暂停位置:
A 因为是使用的是同步日志，所以处于Running状态的工作线程在执行文件IO操作, B 其它的工作线程因为在等待日志文件的复制操作完成，所以是blocking状态，
在执行日志打印操作时会调用到subAppend(E event)方法，这其中有一个同步操作过程：当需要执行备份操作时，拿到锁(triggeringPolicy)的线程会执行备份操作，而其它线程需要等待这个过程执行结束。相关位置的源(ch.qos.logback.core.rolling.RollingFileAppender.subAppend(E event) )如下所示：
/**
* This method differentiates RollingFileAppender from its super class.
*/
@Override
protected void subAppend(E event) {
// The roll-over check must precede actual writing. This is the
// only correct behavior for time driven triggers.
// We need to synchronize on triggeringPolicy so that only one rollover
// occurs at a time
synchronized (triggeringPolicy) {
if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
rollover();
}
}
super.subAppend(event);
}
拿到锁的线程执行备份操作时的核心逻辑如下：
A 首先修改文件名， B 然后验证源文件存储目录/目标文件存储目录是否是在同一个存储卷上： C 如果在同一个卷上，结束， D 如果不在同一个卷上，则执行文件复制操作。
相关位置的源码ch.qos.logback.core.rolling.helper.RenameUtil.rename(String src, String target) 如下所示：
/**
* A relatively robust file renaming method which in case of failure due to
* src and target being on different volumes, falls back onto
* renaming by copying.
*
* @param src
* @param target
* @throws RolloverFailure
*/
public void rename(String src, String target) throws RolloverFailure {
if (src.equals(target)) {
addWarn("Source and target files are the same [" + src + "]. Skipping.");
return;
}
File srcFile = new File(src);
if (srcFile.exists()) {
File targetFile = new File(target);
createMissingTargetDirsIfNecessary(targetFile);
addInfo("Renaming file [" + srcFile + "] to [" + targetFile + "]");
boolean result = srcFile.renameTo(targetFile); // 重命名日志文件
if (!result) {
addWarn("Failed to rename file [" + srcFile + "] as [" + targetFile + "].");
Boolean areOnDifferentVolumes = areOnDifferentVolumes(srcFile, targetFile);
if (Boolean.TRUE.equals(areOnDifferentVolumes)) { // src,target处于不同的存储卷
addWarn("Detected different file systems for source [" + src + "] and target [" + target + "]. Attempting rename by copying.");
renameByCopying(src, target); // 拷贝文件到目标位置
return;
} else { // src,target处于相同的存储卷
addWarn("Please consider leaving the [file] option of " + RollingFileAppender.class.getSimpleName() + " empty.");
addWarn("See also " + RENAMING_ERROR_URL);
}
}
} else {
throw new RolloverFailure("File [" + src + "] does not exist.");
}
}
综上所述，相关服务的出现异常原因在于logback.xml中配置了错误的环境变量，导致实际的日志文件的存储目录(/data/logs)同日志文件备份的存储目录(/opt/log.dir_IS_UNDEFINED)不同，并且因为服务部署的环境是k8s容器，日志文件是/data目录是容器挂载的物理机存储,/opt目录容器内部私有的，/data与/opt不属于同一个存储卷，最终导致logback在执行日志备份时，本应该只需要修改文件名的策略，变成了改名+文件复制的策略，进而引发了该问题。
3.2.2 关于自动现场快照无效问题
有了以上的分析结果，再来看自动现场快照不能正常工作的问题，通过查看相关位置的源码：在执行dump前，打印了一句log,然后通过shell脚本生成现场快照。根据前面分析的结果：当执行日志备份操作时，没有获取到锁的线程会阻塞等待日志备份完成，所以当出现问题时，异步生成快照的线程并没有执行相关的dump的操作。当日志文件备份操作完成后，所用阻塞的线程的阻塞状态也都恢复到Running状态，执行快照生成操作的线程再继续后续操作也就没有意义了。相关位置的源码：
try {
// 执行dump前打印日志！！！
log.info("Trying to dump pid {}..., triggered by {}.", environment.getProperty("PID"), triggerSource);
ProcessBuilder builder = new ProcessBuilder(shell);
builder.redirectErrorStream(true);
Process process = builder.start();
BufferedReader input = new BufferedReader(new InputStreamReader(process.getInputStream()));
String line;
while ((line = input.readLine()) != null) {
log.info(line);
}
input.close();
log.info("Done dump pid {}.", environment.getProperty("PID"));
} catch (Exception e) {
log.error(e.getMessage(), e);
}
4 结束
感谢阅读！
也许你还想看
（▼点击文章标题或封面查看）
2021-03-11
2021-09-09
2022-04-07
2022-05-26
2021-04-01